Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve logging system using logLevel, avoid trace value #15232

Merged
merged 7 commits into from
Jan 8, 2025

Conversation

dhruvmanila
Copy link
Member

@dhruvmanila dhruvmanila commented Jan 3, 2025

Changelog: This PR improves observability in the server by removing the need of using the "trace" value as a means to turn on or off logging. Now, the server logging is solely controlled using the logLevel server setting which defaults to "info". This avoids the confusion where the user is notified about going through the log messages but there aren't any.

Summary

Refer to the VS Code PR (astral-sh/ruff-vscode#659) for details on the change.

This PR changes the following:

  1. Add tracing span for both request (request id and method name) and notification (method name) handler
  2. Remove the RUFF_TRACE environment variable. This was being used to turn on / off logging for the server
  3. Similarly, remove reading the trace value from the initialization options
  4. Remove handling the $/setTrace notification
  5. Remove the specialized TraceLogWriter used for Zed and VS Code (Use $/logTrace for server trace logs in Zed and VS Code #12564)

Regarding the (5) for the Zed editor, the reason that was implemented was because there was no way of looking at the stderr messages in the editor which has been changed. Now, it captures the stderr as part of the "Server Logs". (https://github.com/zed-industries/zed/blob/82492d74a8d0350cba66671c27e282a928fd4c85/crates/language_tools/src/lsp_log.rs#L548-L552)

Question

Regarding (1), I think having just a simple trace level message should be good for now as the spans are not hierarchical. This could be tackled with #12744. The difference between the two:

Using tracing::trace

   0.019243416s DEBUG ThreadId(08) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.026398750s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.026802125s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
   0.026930666s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
   0.026962333s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (1)
   0.027042875s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (2)
   0.027097500s TRACE ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (3)
   0.027107458s DEBUG ruff:worker:0 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.027123541s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   0.027514875s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   0.285689833s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (4)
  45.741101666s TRACE     ruff:main ruff_server::server::api: Received notification "textDocument/didClose"
  47.108745500s TRACE     ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
  47.109802041s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (5)
  47.109926958s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (6)
  47.110027791s DEBUG ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  51.863679125s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/hover" (7)

Using tracing::trace_span

Only logging the enter event:

   0.018638750s DEBUG ThreadId(11) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.025895791s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.026378791s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.026531208s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.026567583s TRACE ruff:main request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.026652541s TRACE ruff:main request{id=2 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.026711041s DEBUG ruff:worker:2 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   0.026729166s DEBUG ruff:worker:1 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.027023083s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   5.197554750s TRACE     ruff:main notification{method="textDocument/didClose"}: ruff_server::server::api: enter
   6.534458000s TRACE     ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   6.535027958s TRACE     ruff:main request{id=3 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   6.535271166s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   6.544240583s TRACE     ruff:main request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.049692458s TRACE     ruff:main request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.508142541s TRACE     ruff:main request{id=6 method="textDocument/hover"}: ruff_server::server::api: enter
   7.872421958s TRACE     ruff:main request{id=7 method="textDocument/hover"}: ruff_server::server::api: enter
   8.024498583s TRACE     ruff:main request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter
  13.895063666s TRACE     ruff:main request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter
  14.774706083s TRACE     ruff:main request{id=10 method="textDocument/hover"}: ruff_server::server::api: enter
  16.058918958s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
  16.060562208s TRACE     ruff:main request{id=11 method="textDocument/diagnostic"}: ruff_server::server::api: enter
  16.061109083s DEBUG ruff:worker:8 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  21.561742875s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
  21.563573791s TRACE     ruff:main request{id=12 method="textDocument/diagnostic"}: ruff_server::server::api: enter
  21.564206750s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  21.826691375s TRACE     ruff:main request{id=13 method="textDocument/codeAction"}: ruff_server::server::api: enter
  22.091080125s TRACE     ruff:main request{id=14 method="textDocument/codeAction"}: ruff_server::server::api: enter

Todo

  • Update documentation (I'll be adding a troubleshooting section under "Editors" as a follow-up which is for all editors)
  • Check for backwards compatibility. I don't think this should break backwards compatibility as it's mainly targeted towards improving the debugging experience.

Before I go on to updating the documentation, I'd appreciate initial review on the chosen approach.

resolves: #14959

Test Plan

Refer to the test plan in astral-sh/ruff-vscode#659.

Example logs at debug level:

   0.010770083s DEBUG ThreadId(15) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.018101916s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.018559916s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.018992375s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
  23.408802375s DEBUG ruff:worker:11 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  24.329127416s DEBUG  ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py

Example logs at trace level:

   0.010296375s DEBUG ThreadId(13) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.017422583s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.018034458s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.018199708s TRACE ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.018251167s DEBUG ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.018528708s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   1.611798417s TRACE ruff:worker:1 request{id=2 method="textDocument/codeAction"}: ruff_server::server::api: enter
   1.861757542s TRACE ruff:worker:4 request{id=3 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.027361792s TRACE ruff:worker:2 request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.851361500s TRACE ruff:worker:5 request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.901690875s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
   7.903063167s TRACE ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   7.903183500s DEBUG ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   8.702385292s TRACE      ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
   8.704106625s TRACE  ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   8.704304875s DEBUG  ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   8.966853458s TRACE  ruff:worker:9 request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter
   9.229622792s TRACE  ruff:worker:6 request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter
  10.513111583s TRACE  ruff:worker:7 request{id=10 method="textDocument/codeAction"}: ruff_server::server::api: enter

Copy link
Contributor

github-actions bot commented Jan 3, 2025

ruff-ecosystem results

Linter (stable)

✅ ecosystem check detected no linter changes.

Linter (preview)

✅ ecosystem check detected no linter changes.

@dhruvmanila dhruvmanila changed the title [WIP] Improve server logging Improve language server logging Jan 3, 2025
@dhruvmanila dhruvmanila changed the title Improve language server logging Use stderr for server log messages Jan 3, 2025
@dhruvmanila dhruvmanila marked this pull request as ready for review January 3, 2025 12:29
@dhruvmanila dhruvmanila changed the title Use stderr for server log messages Improve logging system using logLevel, avoid trace value Jan 7, 2025
crates/red_knot_server/src/logging.rs Outdated Show resolved Hide resolved
crates/red_knot_server/src/logging.rs Show resolved Hide resolved
crates/red_knot_server/src/logging.rs Outdated Show resolved Hide resolved
@@ -26,6 +26,9 @@ macro_rules! define_document_url {
use define_document_url;

pub(super) fn request<'a>(req: server::Request) -> Task<'a> {
let _span =
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this works as expected because the span is dropped as soon as the request method ends. You should be able to see this by adding other tracing logs in a request handler. Those messages should be nested under the request level.

Instead, what we have to do is to create the span here, but only call entered in the thread that process the request OR defer creating the span to the thread that processes the request.

The same applies to notification.

Does this also cover response handlers?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, I've updated them.

No it doesn't cover response handler, I think we decided not to add them for now as the results are large.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No it doesn't cover response handler, I think we decided not to add them for now as the results are large.

Can you tell me more about what you mean by "the results are large"? What I mean is that we may want to add a tracing span to

Box::new(move |response: lsp_server::Response| {
match (response.error, response.result) {
(Some(err), _) => {
tracing::error!(
"Got an error from the client (code {}): {}",
err.code,
err.message
);
Task::nothing()
}
(None, Some(response)) => match serde_json::from_value(response) {
Ok(response) => response_handler(response),
Err(error) => {
tracing::error!("Failed to deserialize response from server: {error}");
Task::nothing()
}
},
(None, None) => {
if TypeId::of::<R::Result>() == TypeId::of::<()>() {
// We can't call `response_handler(())` directly here, but
// since we _know_ the type expected is `()`, we can use
// `from_value(Value::Null)`. `R::Result` implements `DeserializeOwned`,
// so this branch works in the general case but we'll only
// hit it if the concrete type is `()`, so the `unwrap()` is safe here.
response_handler(serde_json::from_value(Value::Null).unwrap());
} else {
tracing::error!(
"Server response was invalid: did not contain a result or error"
);
}
Task::nothing()
}
}
}),

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see, yeah I think it makes sense to add it there as well.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm actually thinking to avoid this for now as currently the output isn't hierarchical so I'll prefer to add this after we merge it with red knot logging.

Need to address the "span" feedback (heading out now for dinner)
dhruvmanila added a commit to astral-sh/ruff-vscode that referenced this pull request Jan 8, 2025
## Summary

Related: astral-sh/ruff#15232

The basic idea is that there will be two channels where the logs will
go:
1. Ruff: Here, all the logs for the extension will go
2. Ruff Language Server: Here, all the server log messages will go and
are captured from the stderr. It will also contain the trace
communications between the client and the server when it's enabled.
3. Ruff Language Server Trace: Here, all the communication messages
between the client and the server will go. **This channel is created
lazily when the value of `ruff.trace.server` is changed to "verbose" or
"messages" for the first time.**

(2) is controlled by the `ruff.logLevel` configuration which defaults to
`info`.

(3) is controlled by the `ruff.trace.server` configuration which
defaults to `off` and can be changed to `messages` and `verbose`. The
difference between them is that the former will only log the method name
for both the request and response while the latter will also log the
request parameters and the response result.

### Red Knot

The end goal is to merge the tracing system with Red knot. Currently,
Red knot's tracing system utilizes the `-v`, `-vv` and `-vvv` flags from
the command-line and `RED_KNOT_LOG` environment variable for
configuration. For the red knot server specifically, we will need to
provide an additional configuration parameter like
`ruff.server.extraEnv` which allows user to fine tune the logging using
the mentioned environment variable. The `ruff.logLevel` will by default
pass `RED_KNOT_LOG=<logLevel>` to allow for easy configuration.

### Why not `window/logMessage` ?

The `window/logMessage` request can be used by the server to notify the
client to log a message at a certain log level. There are a few
disadvantages of using this as oppose to just using stderr:
* It needs to go through the RPC which requires serializing and
de-serializing the messages
* The output format depends on how client handles the message
* The trace channel will get populated with "Received notification
'window/logMessage'" lines
* There's no 'debug' and 'trace' message type the LSP protocol although
the next version is going to include debug type

Additionally, putting the message onto stderr also allows us to use a
custom formatter which is what is being done in red knot and would prove
to be beneficial when merging the tracing setup.

<details><summary>For posterity, here's the patch to use
<code>window/logMessage</code>:</summary>
<p>

```diff
diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs
index 7b367c780..ceedeff21 100644
--- a/crates/ruff_server/src/trace.rs
+++ b/crates/ruff_server/src/trace.rs
@@ -15,6 +15,9 @@
 //! Tracing will write to `stderr` by default, which should appear in the logs for most LSP clients.
 //! A `logFile` path can also be specified in the settings, and output will be directed there instead.
 use core::str;
+use lsp_server::{Message, Notification};
+use lsp_types::notification::{LogMessage, Notification as _};
+use lsp_types::{LogMessageParams, MessageType};
 use serde::Deserialize;
 use std::{
     path::PathBuf,
@@ -22,6 +25,7 @@ use std::{
     sync::{Arc, OnceLock},
 };
 use tracing::level_filters::LevelFilter;
+use tracing_subscriber::fmt::MakeWriter;
 use tracing_subscriber::{
     fmt::{time::Uptime, writer::BoxMakeWriter},
     layer::SubscriberExt,
@@ -73,7 +77,7 @@ pub(crate) fn init_tracing(
 
     let logger = match log_file {
         Some(file) => BoxMakeWriter::new(Arc::new(file)),
-        None => BoxMakeWriter::new(std::io::stderr),
+        None => BoxMakeWriter::new(LogMessageMakeWriter),
     };
     let subscriber = tracing_subscriber::Registry::default().with(
         tracing_subscriber::fmt::layer()
@@ -135,3 +139,61 @@ impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
         Some(LevelFilter::from_level(self.filter.trace_level()))
     }
 }
+
+struct LogMessageMakeWriter;
+
+impl<'a> MakeWriter<'a> for LogMessageMakeWriter {
+    type Writer = LogMessageWriter;
+
+    fn make_writer(&'a self) -> Self::Writer {
+        LogMessageWriter {
+            level: tracing::Level::INFO,
+        }
+    }
+
+    fn make_writer_for(&'a self, meta: &tracing::Metadata<'_>) -> Self::Writer {
+        LogMessageWriter {
+            level: *meta.level(),
+        }
+    }
+}
+
+struct LogMessageWriter {
+    level: tracing::Level,
+}
+
+impl LogMessageWriter {
+    const fn message_type(&self) -> MessageType {
+        match self.level {
+            tracing::Level::ERROR => MessageType::ERROR,
+            tracing::Level::WARN => MessageType::WARNING,
+            tracing::Level::INFO => MessageType::INFO,
+            tracing::Level::DEBUG => MessageType::LOG,
+            tracing::Level::TRACE => MessageType::LOG,
+        }
+    }
+}
+
+impl std::io::Write for LogMessageWriter {
+    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+        let message = str::from_utf8(buf)
+            .map_err(|e| std::io::Error::new(std::io::ErrorKind::InvalidData, e))?
+            .to_owned();
+        LOGGING_SENDER
+            .get()
+            .expect("logging sender should be initialized at this point")
+            .send(Message::Notification(Notification {
+                method: LogMessage::METHOD.to_owned(),
+                params: serde_json::to_value(LogMessageParams {
+                    typ: self.message_type(),
+                    message,
+                })?,
+            }))
+            .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e))?;
+        Ok(buf.len())
+    }
+
+    fn flush(&mut self) -> std::io::Result<()> {
+        Ok(())
+    }
+}
```

</p>
</details> 

## Test Plan

Using the following **VS Code** settings:

```json
{
  "ruff.nativeServer": "on",
  "ruff.path": ["/Users/dhruv/work/astral/ruff/target/debug/ruff"],
  "ruff.trace.server": "verbose",
  "ruff.logLevel": "debug"
}
```

The following video showcases the three channels in VS Code:


https://github.com/user-attachments/assets/53396774-9dfb-4c33-9145-67eaf2395936

Using the following **Zed** settings:

```json
{
  "lsp": {
    "ruff": {
      "binary": {
        "path": "/Users/dhruv/work/astral/ruff/target/debug/ruff",
        "arguments": [
          "server"
        ]
      },
      "initialization_options": {
        "settings": {
          "logLevel": "debug"
        }
      }
    }
  }
}
```

The following video showcases that the stderr messages are captured in
the "Server Logs" window and the RPC window provides the raw request and
response messages:


https://github.com/user-attachments/assets/ee36eb4a-133f-46d3-abb9-366c48793f32

For **Neovim**, there's an open issue
(neovim/neovim#16807) to send stderr messages
to a separate file but currently it gets logged as "ERROR" in the main
LSP log file. There doesn't seem to be any way to hook into the stderr
of the Neovim LSP client for us to provide a solution for Ruff users.
@dhruvmanila dhruvmanila merged commit 1447553 into main Jan 8, 2025
21 checks passed
@dhruvmanila dhruvmanila deleted the dhruv/server-logs branch January 8, 2025 12:48
dcreager added a commit that referenced this pull request Jan 8, 2025
* main:
  [`pylint`] Fix `unreachable` infinite loop (`PLW0101`) (#15278)
  fix invalid syntax in workflow file (#15357)
  [`pycodestyle`] Avoid false positives related to type aliases (`E252`) (#15356)
  [`flake8-builtins`] Disapply `A005` to stub files (#15350)
  Improve logging system using `logLevel`, avoid trace value (#15232)
  [`flake8-builtins`] Rename `A005` and improve its error message (#15348)
  Spruce up docs for pydoclint rules (#15325)
  [`flake8-type-checking`] Apply `TC008` more eagerly in `TYPE_CHECKING` blocks and disapply it in stubs (#15180)
  [red-knot] `knot_extensions` Python API (#15103)
  Display Union of Literals as a Literal (#14993)
  [red-knot] all types are assignable to object (#15332)
  [`ruff`] Parenthesize arguments to `int` when removing `int` would change semantics in `unnecessary-cast-to-int` (`RUF046`) (#15277)
  [`eradicate`] Correctly handle metadata blocks directly followed by normal blocks (`ERA001`) (#15330)
  Narrowing for class patterns in match statements (#15223)
  [red-knot] add call checking (#15200)
  Spruce up docs for `slice-to-remove-prefix-or-suffix` (`FURB188`) (#15328)
  [`internal`] Return statements in finally block point to end block for `unreachable` (`PLW0101`) (#15276)
  [`ruff`] Treat `)` as a regex metacharacter (`RUF043`, `RUF055`) (#15318)
  Use uv consistently throughout the documentation (#15302)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
server Related to the LSP server
Projects
None yet
Development

Successfully merging this pull request may close these issues.

LSP ruff messages about logs, but the LspLog in nvim is empty, is there somewhere else to look?
2 participants